[INFO] fetching crate timesimp 1.0.0...
[INFO] testing timesimp-1.0.0 against master#1f7f8ea0721a3b1eb73e6c6d25cccb371434b320 for pr-154065-1
[INFO] extracting crate timesimp 1.0.0 into /workspace/builds/worker-6-tc1/source
[INFO] started tweaking crates.io crate timesimp 1.0.0
[INFO] removed 0 missing tests
[INFO] finished tweaking crates.io crate timesimp 1.0.0
[INFO] tweaked toml for crates.io crate timesimp 1.0.0 written to /workspace/builds/worker-6-tc1/source/Cargo.toml
[INFO] validating manifest of crates.io crate timesimp 1.0.0 on toolchain 1f7f8ea0721a3b1eb73e6c6d25cccb371434b320
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1f7f8ea0721a3b1eb73e6c6d25cccb371434b320" "metadata" "--manifest-path" "Cargo.toml" "--no-deps", kill_on_drop: false }`
[INFO] crate crates.io crate timesimp 1.0.0 already has a lockfile, it will not be regenerated
[INFO] running `Command { std: CARGO_HOME="/workspace/cargo-home" RUSTUP_HOME="/workspace/rustup-home" "/workspace/cargo-home/bin/cargo" "+1f7f8ea0721a3b1eb73e6c6d25cccb371434b320" "fetch" "--manifest-path" "Cargo.toml", kill_on_drop: false }`
[INFO] [stderr]  Downloading crates ...
[INFO] [stderr]   Downloaded openssl-sys v0.9.107
[INFO] [stderr]   Downloaded jiff-static v0.2.10
[INFO] [stderr]   Downloaded h2 v0.4.9
[INFO] [stderr]   Downloaded openssl v0.10.72
[INFO] [stderr]   Downloaded jiff v0.2.10
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1f7f8ea0721a3b1eb73e6c6d25cccb371434b320" "metadata" "--no-deps" "--format-version=1", kill_on_drop: false }`
[INFO] [stdout] d5e9a684ebbdeffb616b32ec9043689bdb4e187c92affe57f00a9cc86f7c1e80
[INFO] running `Command { std: "docker" "start" "-a" "d5e9a684ebbdeffb616b32ec9043689bdb4e187c92affe57f00a9cc86f7c1e80", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "inspect" "d5e9a684ebbdeffb616b32ec9043689bdb4e187c92affe57f00a9cc86f7c1e80", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "d5e9a684ebbdeffb616b32ec9043689bdb4e187c92affe57f00a9cc86f7c1e80", kill_on_drop: false }`
[INFO] [stdout] d5e9a684ebbdeffb616b32ec9043689bdb4e187c92affe57f00a9cc86f7c1e80
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1f7f8ea0721a3b1eb73e6c6d25cccb371434b320" "build" "--frozen" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] d52a8d19f9f02ebbeabf0a98ffc4e0453893b4979c174a6e2828b0a0f384680e
[INFO] running `Command { std: "docker" "start" "-a" "d52a8d19f9f02ebbeabf0a98ffc4e0453893b4979c174a6e2828b0a0f384680e", kill_on_drop: false }`
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling jiff v0.2.10
[INFO] [stderr]    Compiling proc-macro2 v1.0.94
[INFO] [stderr]    Compiling quote v1.0.40
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]     Finished `dev` profile [unoptimized + debuginfo] target(s) in 10.74s
[INFO] running `Command { std: "docker" "inspect" "d52a8d19f9f02ebbeabf0a98ffc4e0453893b4979c174a6e2828b0a0f384680e", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "d52a8d19f9f02ebbeabf0a98ffc4e0453893b4979c174a6e2828b0a0f384680e", kill_on_drop: false }`
[INFO] [stdout] d52a8d19f9f02ebbeabf0a98ffc4e0453893b4979c174a6e2828b0a0f384680e
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1f7f8ea0721a3b1eb73e6c6d25cccb371434b320" "test" "--frozen" "--no-run" "--message-format=json", kill_on_drop: false }`
[INFO] [stdout] 8179fe6b318180a0a26bb756c3b115af80ebd56890972d10c9253561af7bba21
[INFO] running `Command { std: "docker" "start" "-a" "8179fe6b318180a0a26bb756c3b115af80ebd56890972d10c9253561af7bba21", kill_on_drop: false }`
[INFO] [stderr]    Compiling syn v2.0.100
[INFO] [stderr]    Compiling libc v0.2.171
[INFO] [stderr]    Compiling cc v1.2.20
[INFO] [stderr]    Compiling tracing-core v0.1.33
[INFO] [stderr]    Compiling openssl v0.10.72
[INFO] [stderr]    Compiling log v0.4.27
[INFO] [stderr]    Compiling http-body v1.0.1
[INFO] [stderr]    Compiling bitflags v2.9.0
[INFO] [stderr]    Compiling serde v1.0.219
[INFO] [stderr]    Compiling thread_local v1.1.8
[INFO] [stderr]    Compiling http-body-util v0.1.3
[INFO] [stderr]    Compiling tracing-log v0.2.0
[INFO] [stderr]    Compiling tracing-subscriber v0.3.19
[INFO] [stderr]    Compiling parking_lot_core v0.9.10
[INFO] [stderr]    Compiling mio v1.0.3
[INFO] [stderr]    Compiling socket2 v0.5.9
[INFO] [stderr]    Compiling signal-hook-registry v1.4.5
[INFO] [stderr]    Compiling getrandom v0.3.2
[INFO] [stderr]    Compiling openssl-sys v0.9.107
[INFO] [stderr]    Compiling rand_core v0.9.3
[INFO] [stderr]    Compiling parking_lot v0.12.3
[INFO] [stderr]    Compiling rand_chacha v0.9.0
[INFO] [stderr]    Compiling native-tls v0.2.14
[INFO] [stderr]    Compiling rand v0.9.1
[INFO] [stderr]    Compiling serde_urlencoded v0.7.1
[INFO] [stderr]    Compiling synstructure v0.13.1
[INFO] [stderr]    Compiling zerofrom-derive v0.1.6
[INFO] [stderr]    Compiling yoke-derive v0.7.5
[INFO] [stderr]    Compiling zerovec-derive v0.10.3
[INFO] [stderr]    Compiling displaydoc v0.2.5
[INFO] [stderr]    Compiling tokio-macros v2.5.0
[INFO] [stderr]    Compiling icu_provider_macros v1.5.0
[INFO] [stderr]    Compiling tracing-attributes v0.1.28
[INFO] [stderr]    Compiling openssl-macros v0.1.1
[INFO] [stderr]    Compiling thiserror-impl v2.0.12
[INFO] [stderr]    Compiling tokio v1.44.2
[INFO] [stderr]    Compiling zerofrom v0.1.6
[INFO] [stderr]    Compiling yoke v0.7.5
[INFO] [stderr]    Compiling zerovec v0.10.4
[INFO] [stderr]    Compiling tracing v0.1.41
[INFO] [stderr]    Compiling thiserror v2.0.12
[INFO] [stderr]    Compiling timesimp v1.0.0 (/opt/rustwide/workdir)
[INFO] [stderr]    Compiling tinystr v0.7.6
[INFO] [stderr]    Compiling icu_collections v1.5.0
[INFO] [stderr]    Compiling icu_locid v1.5.0
[INFO] [stderr]    Compiling icu_provider v1.5.0
[INFO] [stderr]    Compiling icu_locid_transform v1.5.0
[INFO] [stderr]    Compiling icu_properties v1.5.1
[INFO] [stderr]    Compiling tokio-util v0.7.15
[INFO] [stderr]    Compiling tokio-native-tls v0.3.1
[INFO] [stderr]    Compiling tower v0.5.2
[INFO] [stderr]    Compiling h2 v0.4.9
[INFO] [stderr]    Compiling icu_normalizer v1.5.0
[INFO] [stderr]    Compiling idna_adapter v1.2.0
[INFO] [stderr]    Compiling idna v1.0.3
[INFO] [stderr]    Compiling url v2.5.4
[INFO] [stderr]    Compiling hyper v1.6.0
[INFO] [stderr]    Compiling hyper-util v0.1.11
[INFO] [stderr]    Compiling hyper-tls v0.6.0
[INFO] [stderr]    Compiling reqwest v0.12.15
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 37.41s
[INFO] running `Command { std: "docker" "inspect" "8179fe6b318180a0a26bb756c3b115af80ebd56890972d10c9253561af7bba21", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "8179fe6b318180a0a26bb756c3b115af80ebd56890972d10c9253561af7bba21", kill_on_drop: false }`
[INFO] [stdout] 8179fe6b318180a0a26bb756c3b115af80ebd56890972d10c9253561af7bba21
[INFO] running `Command { std: "docker" "create" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/target:/opt/rustwide/target:rw,Z" "-v" "/var/lib/crater-agent-workspace/builds/worker-6-tc1/source:/opt/rustwide/workdir:ro,Z" "-v" "/var/lib/crater-agent-workspace/cargo-home:/opt/rustwide/cargo-home:ro,Z" "-v" "/var/lib/crater-agent-workspace/rustup-home:/opt/rustwide/rustup-home:ro,Z" "-e" "SOURCE_DIR=/opt/rustwide/workdir" "-e" "CARGO_TARGET_DIR=/opt/rustwide/target" "-e" "CARGO_INCREMENTAL=0" "-e" "RUST_BACKTRACE=full" "-e" "RUSTFLAGS=--cap-lints=forbid" "-e" "RUSTDOCFLAGS=--cap-lints=forbid" "-e" "CARGO_HOME=/opt/rustwide/cargo-home" "-e" "RUSTUP_HOME=/opt/rustwide/rustup-home" "-w" "/opt/rustwide/workdir" "-m" "1610612736" "--user" "0:0" "--network" "none" "ghcr.io/rust-lang/crates-build-env/linux@sha256:d429b63d4308055ea97f60fb1d3dfca48854a00942f1bd2ad806beaf015945ec" "/opt/rustwide/cargo-home/bin/cargo" "+1f7f8ea0721a3b1eb73e6c6d25cccb371434b320" "test" "--frozen", kill_on_drop: false }`
[INFO] [stdout] 1c5d3c462407e55275377c0f095f09f58324f01ab9991cd7443be33eb5048ea6
[INFO] running `Command { std: "docker" "start" "-a" "1c5d3c462407e55275377c0f095f09f58324f01ab9991cd7443be33eb5048ea6", kill_on_drop: false }`
[INFO] [stderr]     Finished `test` profile [unoptimized + debuginfo] target(s) in 0.27s
[INFO] [stderr]      Running unittests src/lib.rs (/opt/rustwide/target/debug/deps/timesimp-df612d235f3c5d21)
[INFO] [stdout] 
[INFO] [stdout] running 5 tests
[INFO] [stdout] test delta::tests::client_behind_server ... ok
[INFO] [stdout] test delta::tests::clock_went_backwards ... ok
[INFO] [stdout] test delta::tests::client_ahead_of_server ... ok
[INFO] [stdout] test delta::tests::client_equal_server ... ok
[INFO] [stdout] test delta::tests::with_sleep ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.03s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/client_server.rs (/opt/rustwide/target/debug/deps/client_server-33ede81700d42ab7)
[INFO] [stdout] 
[INFO] [stdout] running 10 tests
[INFO] [stdout] [2m2026-03-30T07:59:31.491745Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-03-30T07:59:31.491765Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.491900Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.491913Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.491898Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.492080Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.491928Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.492128Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.492095Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.492176Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.492293Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.492327Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.492605Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-03-30T07:59:31.492898Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.493226Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.492997Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.493727Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.493970Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.493729Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:31.494654Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.495772Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.493317148Z, server: 2026-03-30T07:59:31.494454497Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.495575087Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 128µs 969ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.494446117Z [3mdelta[0m[2m=[0m8µs 380ns
[INFO] [stdout] [2m2026-03-30T07:59:31.495854Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.128969ms [3mdelta[0m[2m=[0m8µs 380ns
[INFO] [stdout] [2m2026-03-30T07:59:31.495889Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m8µs 380ns
[INFO] [stdout] [2m2026-03-30T07:59:31.495910Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m801.445948ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.514948Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.493298088Z, server: 2026-03-30T07:59:36.504580465Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.514736812Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 719µs 362ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.50401745Z [3mdelta[0m[2m=[0m5s 563µs 15ns
[INFO] [stdout] [2m2026-03-30T07:59:31.515047Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.719362ms [3mdelta[0m[2m=[0m5s 563µs 15ns
[INFO] [stdout] [2m2026-03-30T07:59:31.515070Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 563µs 15ns
[INFO] [stdout] [2m2026-03-30T07:59:31.515086Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m489.789627ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.515708Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.493182118Z, server: 2026-03-30T07:59:31.504400365Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.515574652Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 196µs 267ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.504378385Z [3mdelta[0m[2m=[0m21µs 980ns
[INFO] [stdout] [2m2026-03-30T07:59:31.515793Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.196267ms [3mdelta[0m[2m=[0m21µs 980ns
[INFO] [stdout] [2m2026-03-30T07:59:31.515821Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.455393712s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.517089Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.494685268Z, server: 2026-03-30T07:59:36.505834195Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.516968222Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 141µs 477ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.505826745Z [3mdelta[0m[2m=[0m5s 7µs 450ns
[INFO] [stdout] [2m2026-03-30T07:59:31.517866Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.495109397Z, server: 2026-03-30T07:59:31.506240734Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.517751482Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 321µs 42ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.506430439Z [3mdelta[0m[2m=[0m189µs 705ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.517485Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.141477ms [3mdelta[0m[2m=[0m5s 7µs 450ns
[INFO] [stdout] [2m2026-03-30T07:59:31.518140Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 7µs 450ns
[INFO] [stdout] [2m2026-03-30T07:59:31.518325Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m533.225499ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.518610Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.321042ms [3mdelta[0m[2m=[0m189µs 705ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.518790Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.353514723s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.518600Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.493380098Z, server: 2026-03-30T07:59:26.504507515Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.518495562Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 557µs 732ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.50593783Z [3mdelta[0m[2m=[0m5s 1ms 430µs 315ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.518954Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.557732ms [3mdelta[0m[2m=[0m5s 1ms 430µs 315ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.518981Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 1ms 430µs 315ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.518996Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m270.419681ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.524817Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.495998327Z, server: 2026-03-30T07:59:36.515308402Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.52458531Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m14ms 293µs 491ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.510291818Z [3mdelta[0m[2m=[0m5s 5ms 16µs 584ns
[INFO] [stdout] [2m2026-03-30T07:59:31.524920Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m14.293491ms [3mdelta[0m[2m=[0m5s 5ms 16µs 584ns
[INFO] [stdout] [2m2026-03-30T07:59:31.524942Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m5s 5ms 16µs 584ns
[INFO] [stdout] [2m2026-03-30T07:59:31.524956Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m645.003713ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.526612Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.498582336Z, server: 2026-03-30T07:59:36.511524813Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.526481569Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 949µs 616ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.512531952Z [3mdelta[0m[2m=[0m4s 998ms 992µs 861ns
[INFO] [stdout] [2m2026-03-30T07:59:31.526692Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.949616ms [3mdelta[0m[2m=[0m4s 998ms 992µs 861ns
[INFO] [stdout] [2m2026-03-30T07:59:31.526716Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4s 998ms 992µs 861ns
[INFO] [stdout] [2m2026-03-30T07:59:31.526730Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.849597165s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.696487Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.493501328Z, server: 2026-03-30T07:59:31.594844623Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.695621838Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m101ms 60µs 255ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.594561583Z [3mdelta[0m[2m=[0m283µs 40ns
[INFO] [stdout] [2m2026-03-30T07:59:31.697051Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m101.060255ms [3mdelta[0m[2m=[0m283µs 40ns
[INFO] [stdout] [2m2026-03-30T07:59:31.697083Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m283µs 40ns
[INFO] [stdout] [2m2026-03-30T07:59:31.697098Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m523.924714ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:31.816390Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.793492163Z, server: 2026-03-30T07:59:26.80473668Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:31.816063468Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 285µs 652ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:31.804777815Z [3mdelta[0m[2m=[0m5s 41µs 135ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.819582Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.285652ms [3mdelta[0m[2m=[0m5s 41µs 135ns ago
[INFO] [stdout] [2m2026-03-30T07:59:31.819615Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.671451593s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.018127Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.005628561Z, server: 2026-03-30T07:59:37.011785879Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.017939298Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6ms 155µs 368ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.011783929Z [3mdelta[0m[2m=[0m5s 1µs 950ns
[INFO] [stdout] [2m2026-03-30T07:59:32.018218Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.155368ms [3mdelta[0m[2m=[0m5s 1µs 950ns
[INFO] [stdout] [2m2026-03-30T07:59:32.018241Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.664687496s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.083116Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.060272877Z, server: 2026-03-30T07:59:37.071728404Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.082932221Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 329µs 672ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.071602549Z [3mdelta[0m[2m=[0m5s 125µs 855ns
[INFO] [stdout] [2m2026-03-30T07:59:32.083195Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.329672ms [3mdelta[0m[2m=[0m5s 125µs 855ns
[INFO] [stdout] [2m2026-03-30T07:59:32.083216Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.035037057s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.191172Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.172538849Z, server: 2026-03-30T07:59:37.181754537Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.190977804Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m9ms 219µs 477ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.181758326Z [3mdelta[0m[2m=[0m4s 999ms 996µs 211ns
[INFO] [stdout] [2m2026-03-30T07:59:32.191361Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m9.219477ms [3mdelta[0m[2m=[0m4s 999ms 996µs 211ns
[INFO] [stdout] [2m2026-03-30T07:59:32.191494Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m188.382866ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.310695Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.302539487Z, server: 2026-03-30T07:59:32.306516226Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.310503695Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m3ms 982µs 104ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.306521591Z [3mdelta[0m[2m=[0m5µs 365ns ago
[INFO] [stdout] [2m2026-03-30T07:59:32.310795Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m3.982104ms [3mdelta[0m[2m=[0m5µs 365ns ago
[INFO] [stdout] [2m2026-03-30T07:59:32.310817Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m983.594109ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.394597Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.386001856Z, server: 2026-03-30T07:59:37.390196645Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.394385204Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m4ms 191µs 674ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.39019353Z [3mdelta[0m[2m=[0m5s 3µs 115ns
[INFO] [stdout] [2m2026-03-30T07:59:32.394697Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m4.191674ms [3mdelta[0m[2m=[0m5s 3µs 115ns
[INFO] [stdout] [2m2026-03-30T07:59:32.394723Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m601.973873ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.427375Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.221514997Z, server: 2026-03-30T07:59:32.325741121Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.427195766Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m102ms 840µs 384ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.324355381Z [3mdelta[0m[2m=[0m1ms 385µs 740ns
[INFO] [stdout] [2m2026-03-30T07:59:32.427488Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m102.840384ms [3mdelta[0m[2m=[0m1ms 385µs 740ns
[INFO] [stdout] [2m2026-03-30T07:59:32.427509Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m206.930629ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.841327Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.635866154Z, server: 2026-03-30T07:59:32.739635958Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.841130083Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m102ms 631µs 964ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.738498118Z [3mdelta[0m[2m=[0m1ms 137µs 840ns
[INFO] [stdout] [2m2026-03-30T07:59:32.841576Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m102.631964ms [3mdelta[0m[2m=[0m1ms 137µs 840ns
[INFO] [stdout] [2m2026-03-30T07:59:32.841616Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.533199337s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:32.900242Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.877537394Z, server: 2026-03-30T07:59:32.888759441Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:32.899967768Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 215µs 187ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.888752581Z [3mdelta[0m[2m=[0m6µs 860ns
[INFO] [stdout] [2m2026-03-30T07:59:32.900410Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.215187ms [3mdelta[0m[2m=[0m6µs 860ns
[INFO] [stdout] [2m2026-03-30T07:59:32.900503Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m834.03506ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.007784Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:32.97301813Z, server: 2026-03-30T07:59:32.990528926Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.007533352Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m17ms 257µs 611ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.990275741Z [3mdelta[0m[2m=[0m253µs 185ns
[INFO] [stdout] [2m2026-03-30T07:59:33.007879Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m17.257611ms [3mdelta[0m[2m=[0m253µs 185ns
[INFO] [stdout] [2m2026-03-30T07:59:33.007902Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m117.203405ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.038883Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.027535217Z, server: 2026-03-30T07:59:38.034524145Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.038697114Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m5ms 580µs 948ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.033116165Z [3mdelta[0m[2m=[0m5s 1ms 407µs 980ns
[INFO] [stdout] [2m2026-03-30T07:59:33.038989Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m5.580948ms [3mdelta[0m[2m=[0m5s 1ms 407µs 980ns
[INFO] [stdout] [2m2026-03-30T07:59:33.039013Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m719.771835ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.057807Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:31.498640176Z, server: 2026-03-30T07:59:32.273855244Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.0575486Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m779ms 454µs 212ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:32.278094388Z [3mdelta[0m[2m=[0m4ms 239µs 144ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.057917Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m779.454212ms [3mdelta[0m[2m=[0m4ms 239µs 144ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.057949Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m4ms 239µs 144ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.057966Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.57900866s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.148058Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.126369942Z, server: 2026-03-30T07:59:33.13662306Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.147849107Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 739µs 582ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.137109524Z [3mdelta[0m[2m=[0m486µs 464ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.148167Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.739582ms [3mdelta[0m[2m=[0m486µs 464ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.148192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m86.339073ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.153348Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.121370613Z, server: 2026-03-30T07:59:38.138653979Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.153151426Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m15ms 890µs 406ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.137261019Z [3mdelta[0m[2m=[0m5s 1ms 392µs 960ns
[INFO] [stdout] [2m2026-03-30T07:59:33.153469Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m15.890406ms [3mdelta[0m[2m=[0m5s 1ms 392µs 960ns
[INFO] [stdout] [2m2026-03-30T07:59:33.153496Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.958305438s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.258403Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.235789875Z, server: 2026-03-30T07:59:33.247023262Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.258227Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 218µs 562ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.247008437Z [3mdelta[0m[2m=[0m14µs 825ns
[INFO] [stdout] [2m2026-03-30T07:59:33.258508Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.218562ms [3mdelta[0m[2m=[0m14µs 825ns
[INFO] [stdout] [2m2026-03-30T07:59:33.258527Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m915.594861ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.302074Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.299582679Z, server: 2026-03-30T07:59:33.300754969Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.301894699Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 156µs 10ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.300738689Z [3mdelta[0m[2m=[0m16µs 280ns
[INFO] [stdout] [2m2026-03-30T07:59:33.302169Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.15601ms [3mdelta[0m[2m=[0m16µs 280ns
[INFO] [stdout] [2m2026-03-30T07:59:33.302190Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m851.313568ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.400255Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.37767788Z, server: 2026-03-30T07:59:38.388854237Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.400046275Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 184µs 197ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.388862077Z [3mdelta[0m[2m=[0m4s 999ms 992µs 160ns
[INFO] [stdout] [2m2026-03-30T07:59:33.400369Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.184197ms [3mdelta[0m[2m=[0m4s 999ms 992µs 160ns
[INFO] [stdout] [2m2026-03-30T07:59:33.400392Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m239.482426ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.515467Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.492700492Z, server: 2026-03-30T07:59:28.503920319Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.515144516Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 222µs 12ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.503922504Z [3mdelta[0m[2m=[0m5s 2µs 185ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.515571Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.222012ms [3mdelta[0m[2m=[0m5s 2µs 185ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.515594Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m180.030001ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.665757Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.640933415Z, server: 2026-03-30T07:59:38.652139362Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.665535758Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12ms 301µs 171ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.653234586Z [3mdelta[0m[2m=[0m4s 998ms 904µs 776ns
[INFO] [stdout] [2m2026-03-30T07:59:33.665867Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.301171ms [3mdelta[0m[2m=[0m4s 998ms 904µs 776ns
[INFO] [stdout] [2m2026-03-30T07:59:33.665893Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m527.79753ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.700293Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.683685014Z, server: 2026-03-30T07:59:38.691893842Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.70009998Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 207µs 483ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.691892497Z [3mdelta[0m[2m=[0m5s 1µs 345ns
[INFO] [stdout] [2m2026-03-30T07:59:33.700398Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.207483ms [3mdelta[0m[2m=[0m5s 1µs 345ns
[INFO] [stdout] [2m2026-03-30T07:59:33.700518Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.413137696s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.719873Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.697079791Z, server: 2026-03-30T07:59:28.708307418Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.719659145Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 289µs 677ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.708369468Z [3mdelta[0m[2m=[0m5s 62µs 50ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.719973Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.289677ms [3mdelta[0m[2m=[0m5s 62µs 50ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.720000Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.68077735s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.758914Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.735919921Z, server: 2026-03-30T07:59:33.747146128Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.758629006Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 354µs 542ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.747274463Z [3mdelta[0m[2m=[0m128µs 335ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.759036Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.354542ms [3mdelta[0m[2m=[0m128µs 335ns ago
[INFO] [stdout] [2m2026-03-30T07:59:33.759063Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.20185357s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:33.775246Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:33.760627555Z, server: 2026-03-30T07:59:38.767823333Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:33.775034291Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7ms 203µs 368ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:33.767830923Z [3mdelta[0m[2m=[0m4s 999ms 992µs 410ns
[INFO] [stdout] [2m2026-03-30T07:59:33.775435Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.203368ms [3mdelta[0m[2m=[0m4s 999ms 992µs 410ns
[INFO] [stdout] [2m2026-03-30T07:59:33.775497Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.003115, 5001.40798, 4999.99241, 4999.996211, 5005.016584]
[INFO] [stdout] [2m2026-03-30T07:59:33.775539Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.99241 [3mmean[0m[2m=[0m5001.28326 [3mvariance[0m[2m=[0m4.72870580982547 [3mstddev[0m[2m=[0m2.1745587620999047
[INFO] [stdout] [2m2026-03-30T07:59:33.775578Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.003115, 5001.40798, 4999.99241, 4999.996211]
[INFO] [stdout] [2m2026-03-30T07:59:33.775638Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 349µs
[INFO] [stdout] test high_jitter ... ok
[INFO] [stdout] [2m2026-03-30T07:59:34.157149Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.154679567Z, server: 2026-03-30T07:59:34.155838677Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:34.156968596Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m1ms 144µs 514ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:34.155824081Z [3mdelta[0m[2m=[0m14µs 596ns
[INFO] [stdout] [2m2026-03-30T07:59:34.157248Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m1.144514ms [3mdelta[0m[2m=[0m14µs 596ns
[INFO] [stdout] [2m2026-03-30T07:59:34.157272Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.630604819s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:34.197413Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.174687182Z, server: 2026-03-30T07:59:34.186048179Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:34.197223637Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 268µs 227ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:34.185955409Z [3mdelta[0m[2m=[0m92µs 770ns
[INFO] [stdout] [2m2026-03-30T07:59:34.197534Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.268227ms [3mdelta[0m[2m=[0m92µs 770ns
[INFO] [stdout] [2m2026-03-30T07:59:34.197562Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.486464, 0.02198, 0.014825, 0.09277, 0.253185]
[INFO] [stdout] [2m2026-03-30T07:59:34.197589Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.014825 [3mmean[0m[2m=[0m-0.020740800000000004 [3mvariance[0m[2m=[0m0.0769770343807 [3mstddev[0m[2m=[0m0.2774473542506758
[INFO] [stdout] [2m2026-03-30T07:59:34.197614Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.02198, 0.014825, 0.09277, 0.253185]
[INFO] [stdout] [2m2026-03-30T07:59:34.197636Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m95µs
[INFO] [stdout] test client_offset_negative ... ok
[INFO] [stdout] [2m2026-03-30T07:59:34.218766Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.195671247Z, server: 2026-03-30T07:59:39.205880204Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:34.218540161Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 434µs 457ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:34.207105704Z [3mdelta[0m[2m=[0m4s 998ms 774µs 500ns
[INFO] [stdout] [2m2026-03-30T07:59:34.218978Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.434457ms [3mdelta[0m[2m=[0m4s 998ms 774µs 500ns
[INFO] [stdout] [2m2026-03-30T07:59:34.219046Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m398.92015ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:34.582694Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.375532462Z, server: 2026-03-30T07:59:34.482098136Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:34.582501681Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m103ms 484µs 609ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:34.479017071Z [3mdelta[0m[2m=[0m3ms 81µs 65ns
[INFO] [stdout] [2m2026-03-30T07:59:34.582784Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m103.484609ms [3mdelta[0m[2m=[0m3ms 81µs 65ns
[INFO] [stdout] [2m2026-03-30T07:59:34.582806Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m767.216741ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:34.640284Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.619723712Z, server: 2026-03-30T07:59:39.629933729Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:34.640099947Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 188µs 117ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:34.629911829Z [3mdelta[0m[2m=[0m5s 21µs 900ns
[INFO] [stdout] [2m2026-03-30T07:59:34.640375Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.188117ms [3mdelta[0m[2m=[0m5s 21µs 900ns
[INFO] [stdout] [2m2026-03-30T07:59:34.640402Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.0219, 4999.99216, 4998.7744999999995, 4998.904776, 4998.992861]
[INFO] [stdout] [2m2026-03-30T07:59:34.640442Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4998.7744999999995 [3mmean[0m[2m=[0m4999.3372394 [3mvariance[0m[2m=[0m0.3799944591337499 [3mstddev[0m[2m=[0m0.6164369060445277
[INFO] [stdout] [2m2026-03-30T07:59:34.640462Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[4998.7744999999995, 4998.904776, 4998.992861]
[INFO] [stdout] [2m2026-03-30T07:59:34.640475Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 998ms 890µs
[INFO] [stdout] test low_jitter ... ok
[INFO] [stdout] [2m2026-03-30T07:59:34.992963Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.965548096Z, server: 2026-03-30T07:59:34.981536812Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:34.992769949Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m13ms 610µs 926ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:34.979159022Z [3mdelta[0m[2m=[0m2ms 377µs 790ns
[INFO] [stdout] [2m2026-03-30T07:59:34.993065Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m13.610926ms [3mdelta[0m[2m=[0m2ms 377µs 790ns
[INFO] [stdout] [2m2026-03-30T07:59:34.993089Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m337.094892ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:35.136033Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.115498079Z, server: 2026-03-30T07:59:40.125632416Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.135828034Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10ms 164µs 977ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.125663056Z [3mdelta[0m[2m=[0m4s 999ms 969µs 360ns
[INFO] [stdout] [2m2026-03-30T07:59:35.136126Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.164977ms [3mdelta[0m[2m=[0m4s 999ms 969µs 360ns
[INFO] [stdout] [2m2026-03-30T07:59:35.136152Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m46.710088ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:35.136124Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.113665749Z, server: 2026-03-30T07:59:40.124875956Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.136036813Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 185µs 532ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.124851281Z [3mdelta[0m[2m=[0m5s 24µs 675ns
[INFO] [stdout] [2m2026-03-30T07:59:35.136183Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.185532ms [3mdelta[0m[2m=[0m5s 24µs 675ns
[INFO] [stdout] [2m2026-03-30T07:59:35.136204Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.312519101s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:35.201158Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.184525372Z, server: 2026-03-30T07:59:40.192738419Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.200952728Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8ms 213µs 678ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.19273905Z [3mdelta[0m[2m=[0m4s 999ms 999µs 369ns
[INFO] [stdout] [2m2026-03-30T07:59:35.201257Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.213678ms [3mdelta[0m[2m=[0m4s 999ms 999µs 369ns
[INFO] [stdout] [2m2026-03-30T07:59:35.201289Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00195, 5000.001345, 4999.999369, 4999.96936, 5000.563015]
[INFO] [stdout] [2m2026-03-30T07:59:35.201311Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.999369 [3mmean[0m[2m=[0m5000.107007799999 [3mvariance[0m[2m=[0m0.06516934080165211 [3mstddev[0m[2m=[0m0.25528286429302716
[INFO] [stdout] [2m2026-03-30T07:59:35.201331Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00195, 5000.001345, 4999.999369, 4999.96936]
[INFO] [stdout] [2m2026-03-30T07:59:35.201344Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 993µs
[INFO] [stdout] test mid_jitter ... ok
[INFO] [stdout] [2m2026-03-30T07:59:35.354469Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.331720905Z, server: 2026-03-30T07:59:35.343035432Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.354233629Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 256µs 362ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.342977267Z [3mdelta[0m[2m=[0m58µs 165ns
[INFO] [stdout] [2m2026-03-30T07:59:35.354577Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.256362ms [3mdelta[0m[2m=[0m58µs 165ns
[INFO] [stdout] [2m2026-03-30T07:59:35.354609Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00686, 0.058165, -0.189705, -0.128335, 2.37779]
[INFO] [stdout] [2m2026-03-30T07:59:35.354642Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-0.189705 [3mmean[0m[2m=[0m0.424955 [3mvariance[0m[2m=[0m1.2017099025125002 [3mstddev[0m[2m=[0m1.0962252973328521
[INFO] [stdout] [2m2026-03-30T07:59:35.354669Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00686, 0.058165, -0.189705, -0.128335]
[INFO] [stdout] [2m2026-03-30T07:59:35.354692Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m63µs ago
[INFO] [stdout] test client_offset_positive ... ok
[INFO] [stdout] [2m2026-03-30T07:59:35.424339Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.401617188Z, server: 2026-03-30T07:59:30.412824135Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.424143332Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 263µs 72ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.41288026Z [3mdelta[0m[2m=[0m5s 56µs 125ns ago
[INFO] [stdout] [2m2026-03-30T07:59:35.424462Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.263072ms [3mdelta[0m[2m=[0m5s 56µs 125ns ago
[INFO] [stdout] [2m2026-03-30T07:59:35.424496Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-5000.002185, -5000.056125, -5000.041135, -5000.06205, -5001.430315]
[INFO] [stdout] [2m2026-03-30T07:59:35.424538Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-5000.041135 [3mmean[0m[2m=[0m-5000.318362 [3mvariance[0m[2m=[0m0.3869315661446168 [3mstddev[0m[2m=[0m0.6220382352754666
[INFO] [stdout] [2m2026-03-30T07:59:35.424567Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-5000.002185, -5000.056125, -5000.041135, -5000.06205]
[INFO] [stdout] [2m2026-03-30T07:59:35.424590Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 40µs ago
[INFO] [stdout] test server_offset_negative ... ok
[INFO] [stdout] [2m2026-03-30T07:59:35.552619Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.35062132Z, server: 2026-03-30T07:59:35.452016875Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.55240318Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m100ms 890µs 930ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.45151225Z [3mdelta[0m[2m=[0m504µs 625ns
[INFO] [stdout] [2m2026-03-30T07:59:35.552727Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m100.89093ms [3mdelta[0m[2m=[0m504µs 625ns
[INFO] [stdout] [2m2026-03-30T07:59:35.552761Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.504625, 0.28304, 1.13784, 1.38574, 3.081065]
[INFO] [stdout] [2m2026-03-30T07:59:35.552787Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m1.13784 [3mmean[0m[2m=[0m1.278462 [3mvariance[0m[2m=[0m1.2175873381075002 [3mstddev[0m[2m=[0m1.1034434005002252
[INFO] [stdout] [2m2026-03-30T07:59:35.552818Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.504625, 0.28304, 1.13784, 1.38574]
[INFO] [stdout] [2m2026-03-30T07:59:35.552833Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m827µs
[INFO] [stdout] test some_delay ... ok
[INFO] [stdout] [2m2026-03-30T07:59:35.790480Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:35.788945102Z, server: 2026-03-30T07:59:35.789012862Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:35.790192751Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m623µs 824ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.789568926Z [3mdelta[0m[2m=[0m556µs 64ns ago
[INFO] [stdout] [2m2026-03-30T07:59:35.790596Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m623.824µs [3mdelta[0m[2m=[0m556µs 64ns ago
[INFO] [stdout] [2m2026-03-30T07:59:35.790628Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.556064, 0.00838, 0.014596, 0.01628, -0.005365]
[INFO] [stdout] [2m2026-03-30T07:59:35.790649Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.014596 [3mmean[0m[2m=[0m-0.10443459999999997 [3mvariance[0m[2m=[0m0.0638128332378 [3mstddev[0m[2m=[0m0.25261202116645204
[INFO] [stdout] [2m2026-03-30T07:59:35.790676Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.00838, 0.014596, 0.01628, -0.005365]
[INFO] [stdout] [2m2026-03-30T07:59:35.790690Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m8µs
[INFO] [stdout] test no_delay ... ok
[INFO] [stdout] [2m2026-03-30T07:59:36.178874Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:34.638665857Z, server: 2026-03-30T07:59:35.408668496Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:36.178678325Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m770ms 6µs 234ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:35.408672091Z [3mdelta[0m[2m=[0m3µs 595ns ago
[INFO] [stdout] [2m2026-03-30T07:59:36.179192Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m770.006234ms [3mdelta[0m[2m=[0m3µs 595ns ago
[INFO] [stdout] [2m2026-03-30T07:59:36.179276Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m128.124944ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:36.472324Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:36.449670078Z, server: 2026-03-30T07:59:41.460887905Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:36.472113722Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11ms 221µs 822ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:36.4608919Z [3mdelta[0m[2m=[0m4s 999ms 996µs 5ns
[INFO] [stdout] [2m2026-03-30T07:59:36.472454Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.221822ms [3mdelta[0m[2m=[0m4s 999ms 996µs 5ns
[INFO] [stdout] [2m2026-03-30T07:59:36.472488Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00745, 5000.024675, 4999.996005, 5000.125855, 5001.39296]
[INFO] [stdout] [2m2026-03-30T07:59:36.472512Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m4999.996005 [3mmean[0m[2m=[0m5000.309389 [3mvariance[0m[2m=[0m0.3695623985425933 [3mstddev[0m[2m=[0m0.6079164404279533
[INFO] [stdout] [2m2026-03-30T07:59:36.472542Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00745, 5000.024675, 4999.996005, 5000.125855]
[INFO] [stdout] [2m2026-03-30T07:59:36.472564Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 38µs
[INFO] [stdout] test server_offset_positive ... ok
[INFO] [stdout] [2m2026-03-30T07:59:38.080886Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:36.308678593Z, server: 2026-03-30T07:59:37.194714022Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:38.080698493Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m886ms 9µs 950ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:37.194688543Z [3mdelta[0m[2m=[0m25µs 479ns
[INFO] [stdout] [2m2026-03-30T07:59:38.081081Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m886.00995ms [3mdelta[0m[2m=[0m25µs 479ns
[INFO] [stdout] [2m2026-03-30T07:59:38.081198Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m727.067128ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:40.468714Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:38.81553666Z, server: 2026-03-30T07:59:39.643538845Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:40.46853298Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m826ms 498µs 160ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:39.64203482Z [3mdelta[0m[2m=[0m1ms 504µs 25ns
[INFO] [stdout] [2m2026-03-30T07:59:40.468798Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m826.49816ms [3mdelta[0m[2m=[0m1ms 504µs 25ns
[INFO] [stdout] [2m2026-03-30T07:59:40.468818Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.315442649s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.577877Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:41.785728023Z, server: 2026-03-30T07:59:42.681685641Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:43.577679798Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m895ms 975µs 887ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:42.68170391Z [3mdelta[0m[2m=[0m18µs 269ns ago
[INFO] [stdout] [2m2026-03-30T07:59:43.577979Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m895.975887ms [3mdelta[0m[2m=[0m18µs 269ns ago
[INFO] [stdout] [2m2026-03-30T07:59:43.578007Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-0.003595, -4.239144, 1.504025, 0.025479, -0.018269]
[INFO] [stdout] [2m2026-03-30T07:59:43.578026Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m1.504025 [3mmean[0m[2m=[0m-0.5463007999999999 [3mvariance[0m[2m=[0m4.685301523196199 [3mstddev[0m[2m=[0m2.1645557334465195
[INFO] [stdout] [2m2026-03-30T07:59:43.578048Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-0.003595, 1.504025, 0.025479, -0.018269]
[INFO] [stdout] [2m2026-03-30T07:59:43.578062Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m376µs
[INFO] [stdout] test much_delay ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 10 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 12.09s
[INFO] [stdout] 
[INFO] [stderr]      Running tests/in_process.rs (/opt/rustwide/target/debug/deps/in_process-ec9e0f69263559fc)
[INFO] [stdout] 
[INFO] [stdout] running 4 tests
[INFO] [stdout] [2m2026-03-30T07:59:43.590137Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:43.590319Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.590250Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m0s
[INFO] [stdout] [2m2026-03-30T07:59:43.590128Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s ago
[INFO] [stdout] [2m2026-03-30T07:59:43.590451Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.590463Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.591880Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:43.591698165Z, server: 2026-03-30T07:59:43.591714425Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:43.591718285Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m10µs 60ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:43.591708225Z [3mdelta[0m[2m=[0m6µs 200ns
[INFO] [stdout] [2m2026-03-30T07:59:43.591959Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m10.06µs [3mdelta[0m[2m=[0m6µs 200ns
[INFO] [stdout] [2m2026-03-30T07:59:43.591995Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m no offset stored, storing initial delta [3moffset[0m[2m=[0m6µs 200ns
[INFO] [stdout] [2m2026-03-30T07:59:43.592015Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.709377423s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.592225Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:43.592125485Z, server: 2026-03-30T07:59:38.592128555Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:43.592130205Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m2µs 360ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:43.592127845Z [3mdelta[0m[2m=[0m4s 999ms 999µs 290ns ago
[INFO] [stdout] [2m2026-03-30T07:59:43.592280Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m2.36µs [3mdelta[0m[2m=[0m4s 999ms 999µs 290ns ago
[INFO] [stdout] [2m2026-03-30T07:59:43.592299Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m877.977779ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.592266Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:43.592089635Z, server: 2026-03-30T07:59:43.592098365Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:43.592101955Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m6µs 160ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:43.592095795Z [3mdelta[0m[2m=[0m2µs 570ns
[INFO] [stdout] [2m2026-03-30T07:59:43.592337Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m6.16µs [3mdelta[0m[2m=[0m2µs 570ns
[INFO] [stdout] [2m2026-03-30T07:59:43.592358Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m701.521374ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.592749Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m starting delta collection [3msamples[0m[2m=[0m5 [3mcurrent_offset[0m[2m=[0m5s
[INFO] [stdout] [2m2026-03-30T07:59:43.592816Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m0ns [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:43.599824Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:43.599599263Z, server: 2026-03-30T07:59:48.599610683Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:43.599614943Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 840ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:43.599607103Z [3mdelta[0m[2m=[0m5s 3µs 580ns
[INFO] [stdout] [2m2026-03-30T07:59:43.599912Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.84µs [3mdelta[0m[2m=[0m5s 3µs 580ns
[INFO] [stdout] [2m2026-03-30T07:59:43.599934Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.133663009s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:44.295871Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:44.29565966Z, server: 2026-03-30T07:59:44.29567312Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:44.29567756Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 950ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:44.29566861Z [3mdelta[0m[2m=[0m4µs 510ns
[INFO] [stdout] [2m2026-03-30T07:59:44.295969Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.95µs [3mdelta[0m[2m=[0m4µs 510ns
[INFO] [stdout] [2m2026-03-30T07:59:44.295992Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.76053657s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:44.473773Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:44.473549026Z, server: 2026-03-30T07:59:39.473562666Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:44.473566756Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 865ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:44.473557891Z [3mdelta[0m[2m=[0m4s 999ms 995µs 225ns ago
[INFO] [stdout] [2m2026-03-30T07:59:44.473890Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.865µs [3mdelta[0m[2m=[0m4s 999ms 995µs 225ns ago
[INFO] [stdout] [2m2026-03-30T07:59:44.473918Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.455120337s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:44.735746Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:44.735533041Z, server: 2026-03-30T07:59:49.735550911Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:44.735555241Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m11µs 100ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:44.735544141Z [3mdelta[0m[2m=[0m5s 6µs 770ns
[INFO] [stdout] [2m2026-03-30T07:59:44.735918Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m11.1µs [3mdelta[0m[2m=[0m5s 6µs 770ns
[INFO] [stdout] [2m2026-03-30T07:59:44.735974Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.63616246s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:45.302914Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:45.30271827Z, server: 2026-03-30T07:59:45.30273744Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:45.3027359Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 815ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:45.302727085Z [3mdelta[0m[2m=[0m10µs 355ns
[INFO] [stdout] [2m2026-03-30T07:59:45.303019Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.815µs [3mdelta[0m[2m=[0m10µs 355ns
[INFO] [stdout] [2m2026-03-30T07:59:45.303042Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m706.580158ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:45.930896Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:45.930701684Z, server: 2026-03-30T07:59:40.930712674Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:45.930716444Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m7µs 380ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:45.930709064Z [3mdelta[0m[2m=[0m4s 999ms 996µs 390ns ago
[INFO] [stdout] [2m2026-03-30T07:59:45.931010Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m7.38µs [3mdelta[0m[2m=[0m4s 999ms 996µs 390ns ago
[INFO] [stdout] [2m2026-03-30T07:59:45.931038Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.814679887s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:46.010911Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:46.010706034Z, server: 2026-03-30T07:59:46.010724244Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:46.010722384Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 175ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:46.010714209Z [3mdelta[0m[2m=[0m10µs 35ns
[INFO] [stdout] [2m2026-03-30T07:59:46.011020Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.175µs [3mdelta[0m[2m=[0m10µs 35ns
[INFO] [stdout] [2m2026-03-30T07:59:46.011043Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.906534928s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:46.059961Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:46.059676382Z, server: 2026-03-30T07:59:46.059687612Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:46.059692852Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 235ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:46.059684617Z [3mdelta[0m[2m=[0m2µs 995ns
[INFO] [stdout] [2m2026-03-30T07:59:46.060062Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.235µs [3mdelta[0m[2m=[0m2µs 995ns
[INFO] [stdout] [2m2026-03-30T07:59:46.060086Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m1.803815221s [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:46.373878Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:46.373684214Z, server: 2026-03-30T07:59:51.373696454Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:46.373700834Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 310ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:46.373692524Z [3mdelta[0m[2m=[0m5s 3µs 930ns
[INFO] [stdout] [2m2026-03-30T07:59:46.374077Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.31µs [3mdelta[0m[2m=[0m5s 3µs 930ns
[INFO] [stdout] [2m2026-03-30T07:59:46.374154Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m955.04244ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:47.330894Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:47.330687807Z, server: 2026-03-30T07:59:52.330708707Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:47.330713397Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m12µs 795ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:47.330700602Z [3mdelta[0m[2m=[0m5s 8µs 105ns
[INFO] [stdout] [2m2026-03-30T07:59:47.331071Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m12.795µs [3mdelta[0m[2m=[0m5s 8µs 105ns
[INFO] [stdout] [2m2026-03-30T07:59:47.331148Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m553.689127ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:47.748747Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:47.748538243Z, server: 2026-03-30T07:59:42.748551643Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:47.748555493Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 625ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:47.748546868Z [3mdelta[0m[2m=[0m4s 999ms 995µs 225ns ago
[INFO] [stdout] [2m2026-03-30T07:59:47.748858Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.625µs [3mdelta[0m[2m=[0m4s 999ms 995µs 225ns ago
[INFO] [stdout] [2m2026-03-30T07:59:47.748885Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m632.31213ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:47.866131Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:47.865920584Z, server: 2026-03-30T07:59:47.865932614Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:47.865937564Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 490ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:47.865929074Z [3mdelta[0m[2m=[0m3µs 540ns
[INFO] [stdout] [2m2026-03-30T07:59:47.866232Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.49µs [3mdelta[0m[2m=[0m3µs 540ns
[INFO] [stdout] [2m2026-03-30T07:59:47.866259Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m820.151687ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:47.886274Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:47.886072549Z, server: 2026-03-30T07:59:52.886085079Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:47.886089549Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 500ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:47.886081049Z [3mdelta[0m[2m=[0m5s 4µs 30ns
[INFO] [stdout] [2m2026-03-30T07:59:47.886365Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.5µs [3mdelta[0m[2m=[0m5s 4µs 30ns
[INFO] [stdout] [2m2026-03-30T07:59:47.886399Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[5000.00358, 5000.00393, 5000.00403, 5000.00677, 5000.008105]
[INFO] [stdout] [2m2026-03-30T07:59:47.886455Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m5000.00403 [3mmean[0m[2m=[0m5000.005283 [3mvariance[0m[2m=[0m4.1189200002126e-6 [3mstddev[0m[2m=[0m0.002029512256728843
[INFO] [stdout] [2m2026-03-30T07:59:47.886476Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[5000.00358, 5000.00393, 5000.00403]
[INFO] [stdout] [2m2026-03-30T07:59:47.886489Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m5s 3µs
[INFO] [stdout] test positive_starting_offset ... ok
[INFO] [stdout] [2m2026-03-30T07:59:47.927789Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:47.927558749Z, server: 2026-03-30T07:59:47.927576498Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:47.927574849Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 50ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:47.927566799Z [3mdelta[0m[2m=[0m9µs 699ns
[INFO] [stdout] [2m2026-03-30T07:59:47.927891Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.05µs [3mdelta[0m[2m=[0m9µs 699ns
[INFO] [stdout] [2m2026-03-30T07:59:47.927916Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m sleeping to spread out requests [3mdelay[0m[2m=[0m431.62994ms [3mmax_jitter[0m[2m=[0m2s
[INFO] [stdout] [2m2026-03-30T07:59:48.367800Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:48.367569599Z, server: 2026-03-30T07:59:48.367587779Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:48.367585639Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 20ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:48.367577619Z [3mdelta[0m[2m=[0m10µs 160ns
[INFO] [stdout] [2m2026-03-30T07:59:48.367898Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.02µs [3mdelta[0m[2m=[0m10µs 160ns
[INFO] [stdout] [2m2026-03-30T07:59:48.367927Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.01016, 0.009699, 0.010035, 0.010355, 0.0062]
[INFO] [stdout] [2m2026-03-30T07:59:48.367960Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.010035 [3mmean[0m[2m=[0m0.0092898 [3mvariance[0m[2m=[0m3.0403827e-6 [3mstddev[0m[2m=[0m0.001743669320714223
[INFO] [stdout] [2m2026-03-30T07:59:48.367982Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.01016, 0.009699, 0.010035, 0.010355]
[INFO] [stdout] [2m2026-03-30T07:59:48.367996Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m10µs
[INFO] [stdout] test null_offset ... ok
[INFO] [stdout] [2m2026-03-30T07:59:48.382898Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:48.382703416Z, server: 2026-03-30T07:59:43.382716936Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:48.382721086Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 835ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:48.382712251Z [3mdelta[0m[2m=[0m4s 999ms 995µs 315ns ago
[INFO] [stdout] [2m2026-03-30T07:59:48.382998Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.835µs [3mdelta[0m[2m=[0m4s 999ms 995µs 315ns ago
[INFO] [stdout] [2m2026-03-30T07:59:48.383025Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[-4999.99929, -4999.99639, -4999.995225, -4999.995315, -4999.995225]
[INFO] [stdout] [2m2026-03-30T07:59:48.383044Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m-4999.995225 [3mmean[0m[2m=[0m-4999.996289 [3mvariance[0m[2m=[0m3.0572674999314926e-6 [3mstddev[0m[2m=[0m0.0017485043608557265
[INFO] [stdout] [2m2026-03-30T07:59:48.383063Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[-4999.99639, -4999.995225, -4999.995315, -4999.995225]
[INFO] [stdout] [2m2026-03-30T07:59:48.383076Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m4s 999ms 995µs ago
[INFO] [stdout] test negative_starting_offset ... ok
[INFO] [stdout] [2m2026-03-30T07:59:48.687924Z[0m [35mTRACE[0m [1mnew[0m[1m{[0m[3mresponse[0m[2m=[0mResponse { client: 2026-03-30T07:59:48.6877301Z, server: 2026-03-30T07:59:48.687742Z } [3mcurrent[0m[2m=[0m2026-03-30T07:59:48.68774721Z[1m}[0m[2m:[0m [2mtimesimp::delta[0m[2m:[0m response processing internals [3mlatency[0m[2m=[0m8µs 555ns [3mlocal_at_midpoint[0m[2m=[0m2026-03-30T07:59:48.687738655Z [3mdelta[0m[2m=[0m3µs 345ns
[INFO] [stdout] [2m2026-03-30T07:59:48.688016Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m obtained raw offset from server [3mlatency[0m[2m=[0m8.555µs [3mdelta[0m[2m=[0m3µs 345ns
[INFO] [stdout] [2m2026-03-30T07:59:48.688040Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m response deltas sorted by latency [3mdeltas[0m[2m=[0m[0.00257, 0.002995, 0.00354, 0.003345, 0.00451]
[INFO] [stdout] [2m2026-03-30T07:59:48.688057Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m statistics about response deltas [3mmedian[0m[2m=[0m0.00354 [3mmean[0m[2m=[0m0.003392 [3mvariance[0m[2m=[0m5.268325000000001e-7 [3mstddev[0m[2m=[0m0.0007258322809024136
[INFO] [stdout] [2m2026-03-30T07:59:48.688076Z[0m [35mTRACE[0m [2mtimesimp[0m[2m:[0m eliminated outliers [3minliers[0m[2m=[0m[0.002995, 0.00354, 0.003345]
[INFO] [stdout] [2m2026-03-30T07:59:48.688088Z[0m [34mDEBUG[0m [2mtimesimp[0m[2m:[0m storing calculated offset [3moffset[0m[2m=[0m3µs
[INFO] [stdout] test zero_offset ... ok
[INFO] [stderr]    Doc-tests timesimp
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 5.11s
[INFO] [stdout] 
[INFO] [stdout] 
[INFO] [stdout] running 2 tests
[INFO] [stdout] test src/lib.rs - Timesimp::attempt_sync (line 220) ... ignored
[INFO] [stdout] test src/lib.rs - (line 24) - compile ... ok
[INFO] [stdout] 
[INFO] [stdout] test result: ok. 1 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 0.00s
[INFO] [stdout] 
[INFO] [stdout] all doctests ran in 1.91s; merged doctests compilation took 1.86s
[INFO] running `Command { std: "docker" "inspect" "1c5d3c462407e55275377c0f095f09f58324f01ab9991cd7443be33eb5048ea6", kill_on_drop: false }`
[INFO] running `Command { std: "docker" "rm" "-f" "1c5d3c462407e55275377c0f095f09f58324f01ab9991cd7443be33eb5048ea6", kill_on_drop: false }`
[INFO] [stdout] 1c5d3c462407e55275377c0f095f09f58324f01ab9991cd7443be33eb5048ea6
